**** dT 0.000 * top TEST ../../../bin/varnishtest/tests/v00003.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build/bin/varnishtest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** top extmacro def bad_backend=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:50368 **** top extmacro def listen_addr=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build **** top extmacro def topsrc=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build/.. **** top macro def testdir=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build/bin/varnishtest/../../../bin/varnishtest/tests **** top macro def tmpdir=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/_vtest_tmp/vtc.614167.60bb8809 **** top macro def vtcid=vtc.614167.60bb8809 ** top === varnishtest "vcl.state coverage tests" * top VTEST vcl.state coverage tests ** top === server s1 -repeat 20 { ** s1 Starting server **** dT 0.001 **** s1 macro def s1_addr=fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 macro def s1_port=37244 **** s1 macro def s1_sock=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:37244 * s1 Listen on [fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:37244 ** top === varnish v1 -arg "-p vcl_cooldown=1" \ ** s1 Started on [fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:37244 (20 iterations) **** dT 0.010 ** v1 Launch *** v1 CMD: cd ${pwd} && exec varnishd -d -n /tmp/vtest.gcc4.7.3_m64_IPv6_uffix/_vtest_tmp/vtc.614167.60bb8809/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:0' -M 'fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 61135' -P /tmp/vtest.gcc4.7.3_m64_IPv6_uffix/_vtest_tmp/vtc.614167.60bb8809/v1/varnishd.pid -p vmod_path=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build/vmod/.libs -p vcl_cooldown=1 -p thread_pool_min=5 -p thread_pool_max=5 *** v1 CMD: cd /tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build/bin/varnishtest && exec varnishd -d -n /tmp/vtest.gcc4.7.3_m64_IPv6_uffix/_vtest_tmp/vtc.614167.60bb8809/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:0' -M 'fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 61135' -P /tmp/vtest.gcc4.7.3_m64_IPv6_uffix/_vtest_tmp/vtc.614167.60bb8809/v1/varnishd.pid -p vmod_path=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/varnish-cache/varnish-trunk/_build/vmod/.libs -p vcl_cooldown=1 -p thread_pool_min=5 -p thread_pool_max=5 *** v1 PID: 614177 **** v1 macro def v1_pid=614177 **** v1 macro def v1_name=/tmp/vtest.gcc4.7.3_m64_IPv6_uffix/_vtest_tmp/vtc.614167.60bb8809/v1 **** dT 0.040 *** v1 debug|Warning: mlock() of VSM failed: Not owner (1) **** dT 0.042 *** v1 debug|Debug: Version: varnish-trunk revision 52a6d38c5709cf1a92896d5dc2e984962ce10446 *** v1 debug|Debug: Platform: -jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|200 290 *** v1 debug|----------------------------- *** v1 debug|Varnish Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|-jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|varnish-trunk revision 52a6d38c5709cf1a92896d5dc2e984962ce10446 *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 0.141 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 6 *** v1 CLI RX 107 **** v1 CLI RX|xgbqymqcobufngukcmjcejrqdoqamqvg **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 5d5454276d5a28ee400e71e7fda183ee437e118519eb9c731dbd20dc0f4f67f9 **** dT 0.142 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Varnish Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|-jsolaris,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|varnish-trunk revision 52a6d38c5709cf1a92896d5dc2e984962ce10446 **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\timport debug; **** v1 CLI TX|\tbackend default { **** v1 CLI TX|\t\t.host = "fc00:a462:8e9e:946a:5df3:31c6:d23:18dc"; **** v1 CLI TX|\t\t.port = "37244"; **** v1 CLI TX|\t\t.probe = { .interval = 1s; } **** v1 CLI TX|\t} **** v1 CLI TX|\tbackend noprobe { **** v1 CLI TX|\t\t.host = "fc00:a462:8e9e:946a:5df3:31c6:d23:18dc"; **** v1 CLI TX|\t\t.port = "37244"; **** v1 CLI TX|\t} **** v1 CLI TX|\tsub vcl_backend_fetch { **** v1 CLI TX|\t\tset bereq.backend = noprobe; **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.242 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.342 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.442 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.542 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.556 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid **** v1 CLI RX|Message from C-compiler: **** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 0.567 *** v1 debug|Debug: *** v1 debug| Child (614255) Started **** dT 0.598 *** v1 debug|Child launched OK **** dT 0.600 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 52245 *** v1 debug|Info: Child (614255) said Child starts *** v1 debug|Info: Child (614255) said Security: Privilege proc_setid missing, will not change uid/gid ** s1 === rxreq *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 35490 **** v1 CLI TX|debug.xid 1000 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:24 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r *** v1 CLI RX 200 **** v1 CLI RX|a0 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 35490 ** v1 Listen on fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 35490 ** s1 === delay .2 **** v1 macro def v1_addr=fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** v1 macro def v1_port=35490 **** v1 macro def v1_sock=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 macro def v1_a0_addr=fc00:a462:8e9e:946a:5df3:31c6:d23:18dc *** s1 delaying 0.2 second(s) **** v1 macro def v1_a0_port=35490 **** v1 macro def v1_a0_sock=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** dT 0.643 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1729856243.718530/vgc.so 1auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1729856243.718530/vgc.so" as "vcl1" **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=[fc00:a462:8e9e:946a:5df3:31c6:d23:18dc]:35490 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 48 a0 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 35490 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 48 a0 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 35490 **** dT 0.700 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 **** dT 0.702 ** v1 as expected: VBE.vcl1.default.happy (3) >= 0 (0) ** top === varnish v1 -expect VBE.vcl1.noprobe.happy > 9223372036854775... **** dT 0.703 ** v1 as expected: VBE.vcl1.noprobe.happy (18446744073709551615) > 9223372036854775808 (9223372036854775808) ** top === varnish v1 -expect !VBE.vcl2.default.happy **** dT 0.800 *** s1 shutting fd 4 **** dT 0.843 **** v1 vsl| 0 Backend_health - default Went healthy -6--X-RH 3 3 8 0.200730 0.066910 "HTTP/1.1 200 OK" **** dT 1.800 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 59862 ** s1 === rxreq **** dT 1.801 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:25 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 2.001 *** s1 shutting fd 4 **** dT 2.043 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 4 3 8 0.200464 0.100298 "HTTP/1.1 200 OK" **** dT 3.001 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 51518 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:26 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 3.201 *** s1 shutting fd 4 **** dT 3.244 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 5 3 8 0.200440 0.125334 "HTTP/1.1 200 OK" **** dT 3.644 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856247 1.0 **** dT 4.201 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 64536 ** s1 === rxreq **** dT 4.202 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:27 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 4.402 *** s1 shutting fd 4 **** dT 4.444 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 6 3 8 0.200436 0.144109 "HTTP/1.1 200 OK" **** dT 5.402 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 47125 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:28 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 5.602 *** s1 shutting fd 4 **** dT 5.645 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 7 3 8 0.200503 0.158208 "HTTP/1.1 200 OK" **** dT 5.708 ** v1 not found (as expected): VBE.vcl2.default.happy ** top === varnish v1 -cliok "backend.list -p *.*" **** v1 CLI TX|backend.list -p *.* *** v1 CLI RX 200 **** v1 CLI RX|Backend name Admin Probe Health Last change **** v1 CLI RX|vcl1.default probe 7/8 healthy Fri, 25 Oct 2024 11:37:24 GMT **** v1 CLI RX| Current states good: 7 threshold: 3 window: 8 **** v1 CLI RX| Average response time of good probes: 0.158208 **** v1 CLI RX| Oldest ================================================== Newest **** v1 CLI RX| -----------------------------------------------------------66666 Good IPv6 **** v1 CLI RX| -----------------------------------------------------------XXXXX Good Xmit **** v1 CLI RX| -----------------------------------------------------------RRRRR Good Recv **** v1 CLI RX| ---------------------------------------------------------HHHHHHH Happy **** v1 CLI RX| **** v1 CLI RX|vcl1.noprobe healthy 0/0 healthy Fri, 25 Oct 2024 11:37:24 GMT **** v1 CLI RX|vcl1.dir_warmcold healthy 0/0 healthy Fri, 25 Oct 2024 11:37:24 GMT ** v1 CLI 200 ** top === varnish v1 -vcl { **** v1 CLI TX|vcl.inline vcl2 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\tbackend default { **** v1 CLI TX|\t\t.host = "fc00:a462:8e9e:946a:5df3:31c6:d23:18dc"; **** v1 CLI TX|\t\t.port = "37244"; **** v1 CLI TX|\t\t.probe = { .interval = 1s; } **** v1 CLI TX|\t} **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 5.745 **** v1 vsl| 0 CLI - Rd backend.list -p *.* **** v1 vsl| 0 CLI - Wr 200 766 Backend name Admin Probe Health Last change vcl1.default probe 7/8 healthy Fri, 25 Oct 2024 11:37:24 GMT Current states good: 7 threshold: 3 window: 8 Average response time of good probes: 0.158208 Old **** dT 6.080 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid **** v1 CLI RX|Message from C-compiler: **** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|Security: Privilege proc_setid missing, will not change uid/gid **** v1 CLI TX|vcl.use vcl2 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 61754 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** s1 === rxreq ** top === delay .4 *** top delaying 0.4 second(s) **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:29 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 6.145 **** v1 vsl| 0 CLI - Rd vcl.load vcl2 vcl_vcl2.1729856249.284615/vgc.so 1auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl2.1729856249.284615/vgc.so" as "vcl2" **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** dT 6.280 *** s1 shutting fd 4 **** dT 6.345 **** v1 vsl| 0 Backend_health - default Went healthy -6--X-RH 3 3 8 0.200487 0.066829 "HTTP/1.1 200 OK" **** dT 6.480 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (127) >= 0 (0) ** top === varnish v1 -expect VBE.vcl2.default.happy >= 0 ** v1 as expected: VBE.vcl2.default.happy (7) >= 0 (0) ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 0 Debug "vcl1: VCL_EVENT_COLD" ** l1 === expect * 0 Debug "vcl1: VCL_EVENT_WARM" **** dT 6.481 ** top === varnish v1 -cliok "vcl.state vcl1 cold" **** v1 CLI TX|vcl.state vcl1 cold **** l1 begin| *** l1 test | expect * 0 Debug vcl1: VCL_EVENT_COLD *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *cold *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list *** v1 CLI RX 200 **** v1 CLI RX|available cold cold 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === delay .4 *** top delaying 0.4 second(s) **** dT 6.491 **** l1 match| 0 Debug - vcl1: VCL_EVENT_COLD *** l1 test | expect * 0 Debug vcl1: VCL_EVENT_WARM **** dT 6.545 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0cold **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_COLD **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available cold cold 0 vcl1 active auto warm 0 vcl2 **** dT 6.646 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856250 1.0 **** dT 6.881 ** top === varnish v1 -expect !VBE.vcl1.default.happy **** dT 7.280 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 40824 ** s1 === rxreq **** dT 7.281 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:30 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 7.481 *** s1 shutting fd 4 **** dT 7.546 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 4 3 8 0.200519 0.100252 "HTTP/1.1 200 OK" **** dT 8.481 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 36397 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:32 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 8.681 *** s1 shutting fd 4 **** dT 8.747 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 5 3 8 0.200473 0.125307 "HTTP/1.1 200 OK" **** dT 9.647 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856253 1.0 **** dT 9.681 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 38225 ** s1 === rxreq **** dT 9.682 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:33 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 9.882 *** s1 shutting fd 4 **** dT 9.947 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 6 3 8 0.200471 0.144098 "HTTP/1.1 200 OK" **** dT 10.882 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 40854 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:34 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 11.082 *** s1 shutting fd 4 **** dT 11.148 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 7 3 8 0.200478 0.158193 "HTTP/1.1 200 OK" **** dT 11.886 ** v1 not found (as expected): VBE.vcl1.default.happy ** top === varnish v1 -clierr 300 "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 **** dT 11.887 *** v1 CLI RX 300 **** v1 CLI RX|VCL 'vcl1' is cold - set to auto or warm first ** v1 CLI 300 ** top === varnish v1 -cliok "vcl.state vcl1 warm" **** v1 CLI TX|vcl.state vcl1 warm *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.use vcl1" **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 CLI 200 ** top === varnish v1 -cliexpect "active *warm *warm *[0-9]+ *vcl1\\s+a... *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 55619 ** s1 === rxreq **** v1 CLI TX|vcl.list *** v1 CLI RX 200 **** v1 CLI RX|active warm warm 0 vcl1 **** v1 CLI RX|available auto warm 0 vcl2 ** v1 CLI 200 ** top === delay .4 *** top delaying 0.4 second(s) **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:35 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 11.888 **** l1 match| 0 Debug - vcl1: VCL_EVENT_WARM **** l1 done | **** dT 11.948 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1warm **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.use vcl1 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 active warm warm 0 vcl1 available auto warm 0 vcl2 **** dT 12.087 *** s1 shutting fd 4 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 52717 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:35 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 12.148 **** v1 vsl| 0 Backend_health - default Went healthy -6--X-RH 3 3 8 0.200531 0.066844 "HTTP/1.1 200 OK" **** dT 12.287 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (7) >= 0 (0) ** top === varnish v1 -expect VBE.vcl2.default.happy >= 0 ** v1 as expected: VBE.vcl2.default.happy (127) >= 0 (0) ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === delay 4 *** top delaying 4 second(s) *** s1 shutting fd 4 **** dT 12.348 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 8 3 8 0.205061 0.169910 "HTTP/1.1 200 OK" **** dT 12.648 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856256 1.0 **** dT 13.087 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 37604 ** s1 === rxreq **** dT 13.088 **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:36 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 13.288 *** s1 shutting fd 4 **** dT 13.349 **** v1 vsl| 0 CLI - Rd vcl.state vcl2 0auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 4 3 8 0.200463 0.100249 "HTTP/1.1 200 OK" **** dT 14.288 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 61466 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:37 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 14.488 *** s1 shutting fd 4 **** dT 14.549 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 5 3 8 0.200448 0.125298 "HTTP/1.1 200 OK" **** dT 15.818 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856259 1.0 **** dT 15.834 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 37107 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:39 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 16.038 *** s1 shutting fd 4 **** dT 16.133 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 6 3 8 0.293284 0.167295 "HTTP/1.1 200 OK" **** dT 16.298 ** top === varnish v1 -cliexpect "active *warm *warm *[0-9]+ *vcl1\\s+a... **** v1 CLI TX|vcl.list **** dT 16.774 *** v1 CLI RX 200 **** v1 CLI RX|active warm warm 0 vcl1 **** v1 CLI RX|available auto cold 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -expect !VBE.vcl2.default.happy **** dT 17.003 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 active warm warm 0 vcl1 available auto cold 0 vcl2 **** dT 17.357 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 45565 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:40 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 17.558 *** s1 shutting fd 4 **** dT 17.892 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 7 3 8 0.212957 0.178710 "HTTP/1.1 200 OK" **** dT 18.641 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 61173 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:42 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 18.731 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856262 1.0 **** dT 18.841 *** s1 shutting fd 4 **** dT 18.931 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 8 3 8 0.200609 0.184185 "HTTP/1.1 200 OK" **** dT 19.841 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 47082 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:43 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r **** dT 19.842 ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 20.042 *** s1 shutting fd 4 **** dT 20.059 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 8 3 8 0.200510 0.188266 "HTTP/1.1 200 OK" **** dT 21.042 *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 46623 ** s1 === rxreq **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:44 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 21.242 *** s1 shutting fd 4 **** dT 21.305 **** v1 vsl| 0 Backend_health - default Still healthy -6--X-RH 8 3 8 0.200680 0.191370 "HTTP/1.1 200 OK" **** dT 21.639 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856265 1.0 **** dT 21.852 ** v1 not found (as expected): VBE.vcl2.default.happy ** top === varnish v1 -cliok "vcl.use vcl2" **** v1 CLI TX|vcl.use vcl2 **** dT 21.853 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl2' now active ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *warm *warm *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list *** s1 accepted fd 4 fc00:a462:8e9e:946a:5df3:31c6:d23:18dc 61300 ** s1 === rxreq *** v1 CLI RX 200 **** v1 CLI RX|available warm warm 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === delay 4 *** top delaying 4 second(s) **** s1 rxhdr|GET / HTTP/1.1\r **** s1 rxhdr|Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc\r **** s1 rxhdr|Connection: close\r **** s1 rxhdr|\r **** s1 rxhdrlen = 83 **** s1 http[ 0] |GET **** s1 http[ 1] |/ **** s1 http[ 2] |HTTP/1.1 **** s1 http[ 3] |Host: fc00:a462:8e9e:946a:5df3:31c6:d23:18dc **** s1 http[ 4] |Connection: close **** s1 bodylen = 0 ** s1 === txresp **** s1 txresp|HTTP/1.1 200 OK\r **** s1 txresp|Date: Fri, 25 Oct 2024 11:37:45 GMT\r **** s1 txresp|Server: s1\r **** s1 txresp|Content-Length: 0\r **** s1 txresp|\r ** s1 === delay .2 *** s1 delaying 0.2 second(s) **** dT 21.940 **** v1 vsl| 0 CLI - Rd vcl.state vcl2 1auto **** v1 vsl| 0 Backend_health - default Still sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.use vcl2 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available warm warm 0 vcl1 active auto warm 0 vcl2 **** dT 22.053 *** s1 shutting fd 4 ** s1 Ending **** dT 22.140 **** v1 vsl| 0 Backend_health - default Went healthy -6--X-RH 3 3 8 0.200618 0.066873 "HTTP/1.1 200 OK" **** dT 24.293 **** v1 vsl| 0 Backend_health - default Still healthy -6--Xr-- 7 3 8 0.000000 0.191370 "Poll error 145 (Connection timed out)" **** dT 24.747 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856268 1.0 **** dT 25.151 **** v1 vsl| 0 Backend_health - default Still healthy -6--Xr-- 3 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 25.854 ** top === varnish v1 -cliexpect "available *warm *warm *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list *** v1 CLI RX 200 **** v1 CLI RX|available warm warm 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 ** v1 as expected: VBE.vcl1.default.happy (2046) >= 0 (0) ** top === varnish v1 -expect VBE.vcl2.default.happy >= 0 ** v1 as expected: VBE.vcl2.default.happy (14) >= 0 (0) ** top === varnish v1 -clierr 300 "vcl.state vcl2 cold" **** v1 CLI TX|vcl.state vcl2 cold *** v1 CLI RX 300 **** v1 CLI RX|Cannot set the active VCL cold. ** v1 CLI 300 ** top === varnish v1 -cliok "vcl.state vcl1 auto" **** v1 CLI TX|vcl.state vcl1 auto *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliexpect "available *auto *warm *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list *** v1 CLI RX 200 **** v1 CLI RX|available auto warm 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === delay .4 *** top delaying 0.4 second(s) **** dT 25.951 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available warm warm 0 vcl1 active auto warm 0 vcl2 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1auto **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available auto warm 0 vcl1 active auto warm 0 vcl2 **** dT 26.254 ** top === varnish v1 -expect VBE.vcl1.default.happy >= 0 **** dT 26.255 ** v1 as expected: VBE.vcl1.default.happy (2046) >= 0 (0) ** top === delay 4 *** top delaying 4 second(s) **** dT 26.989 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 0auto **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_COLD **** v1 vsl| 0 CLI - Wr 200 0 **** dT 27.292 **** v1 vsl| 0 Backend_health - default Still sick -----r-H 2 3 8 0.000000 0.000000 "Poll error 145 (Connection timed out)" **** dT 27.646 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856271 1.0 **** dT 34.392 **** v1 vsl| 0 Backend_health - default Still healthy -6--Xr-- 3 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 36.124 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856279 1.0 **** dT 37.688 **** v1 vsl| 0 Backend_health - default Still healthy -6--Xr-- 3 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 38.046 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856281 1.0 **** dT 40.712 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856284 1.0 **** v1 vsl| 0 Backend_health - default Still healthy -6--Xr-- 3 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 43.720 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856287 1.0 **** dT 43.826 **** v1 vsl| 0 Backend_health - default Still healthy -6--Xr-- 3 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 46.813 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856290 1.0 **** dT 46.952 **** v1 vsl| 0 Backend_health - default Went sick -6--Xr-- 2 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 49.754 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856293 1.0 **** dT 49.984 **** v1 vsl| 0 Backend_health - default Still sick -6--Xr-- 1 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 51.205 ** top === varnish v1 -cliexpect "available *auto *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 51.232 **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available auto cold 0 vcl1 active auto warm 0 vcl2 **** dT 51.245 *** v1 CLI RX 200 **** v1 CLI RX|available auto cold 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -expect !VBE.vcl1.default.happy **** dT 52.847 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856296 1.0 **** dT 52.966 **** v1 vsl| 0 Backend_health - default Still sick -6--Xr-- 0 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 55.844 **** v1 vsl| 0 CLI - Rd ping **** v1 vsl| 0 CLI - Wr 200 19 PONG 1729856299 1.0 **** dT 56.067 **** v1 vsl| 0 Backend_health - default Still sick -6--Xr-- 0 3 8 0.000000 0.066873 "Poll error 145 (Connection timed out)" **** dT 58.204 ** v1 not found (as expected): VBE.vcl1.default.happy ** top === varnish v1 -cliok "param.set max_esi_depth 42" **** v1 CLI TX|param.set max_esi_depth 42 **** dT 58.234 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -clierr 300 "vcl.state vcl1 warm" **** v1 CLI TX|vcl.state vcl1 warm **** dT 58.289 *** v1 CLI RX 300 **** v1 CLI RX|Failed **** v1 CLI RX|Message: **** v1 CLI RX|\tmax_esi_depth is not the answer. ** v1 CLI 300 ** top === varnish v1 -cliexpect "available *auto *cold *[0-9]+ *vcl1\\... **** v1 CLI TX|vcl.list **** dT 58.342 **** v1 vsl| 0 CLI - Rd vcl.state vcl1 1warm **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 300 71 Failed Message: max_esi_depth is not the answer. **** v1 vsl| 0 CLI - Rd vcl.list **** v1 vsl| 0 CLI - Wr 200 70 available auto cold 0 vcl1 active auto warm 0 vcl2 **** dT 58.361 *** v1 CLI RX 200 **** v1 CLI RX|available auto cold 0 vcl1 **** v1 CLI RX|active auto warm 0 vcl2 ** v1 CLI 200 ** top === varnish v1 -cliok stop **** v1 CLI TX|stop **** dT 58.397 *** v1 debug|Debug: Stopping Child **** dT 58.451 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 58.651 *** v1 debug|Info: Child (614255) said Child dies **** dT 59.073 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.state vcl1 warm" **** v1 CLI TX|vcl.state vcl1 warm **** dT 59.081 *** v1 debug|Info: Child (614255) ended *** v1 debug|Debug: Child cleanup complete **** dT 59.120 *** v1 CLI RX 200 ** v1 CLI 200 ** top === varnish v1 -cliok "vcl.list" **** v1 CLI TX|vcl.list **** dT 59.144 *** v1 CLI RX 200 **** v1 CLI RX|available warm warm - vcl1 **** v1 CLI RX|active auto warm - vcl2 ** v1 CLI 200 ** top === varnish v1 -clierr 300 start **** v1 CLI TX|start **** dT 59.212 *** v1 debug|Debug: Child (626789) Started **** dT 59.341 *** v1 debug|Child launched OK **** dT 59.361 *** v1 debug|Error: Child (626789) Pushing vcls failed: *** v1 debug|VCL "vcl1" Failed warmup *** v1 debug|Message: *** v1 debug|\tmax_esi_depth is not the answer. *** v1 debug|Debug: Stopping Child **** dT 59.364 *** v1 debug|Info: Child (626789) said Child starts *** v1 debug|Info: Child (626789) said Security: Privilege proc_setid missing, will not change uid/gid **** dT 59.446 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1729856243.718530/vgc.so 1warm **** v1 vsl| 0 Backend_health - default Went sick -------H 2 3 8 0.000000 0.000000 "" **** v1 vsl| 0 Debug - vcl1: VCL_EVENT_WARM **** v1 vsl| 0 CLI - Wr 300 67 VCL "vcl1" Failed warmup Message: max_esi_depth is not the answer. **** dT 59.557 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 59.691 *** v1 debug|Info: Child (626789) said Child dies # top TEST ../../../bin/varnishtest/tests/v00003.vtc TIMED OUT (kill -9) # top TEST ../../../bin/varnishtest/tests/v00003.vtc FAILED (60.062) signal=9